Crate pyo3_log

A bridge from Rust to Python logging

The library can be used to install a logger into Rust that will send the messages over to the Python logging. This can be useful when writing a native Python extension module in Rust and it is desirable to log from the Rust side too.

The library internally depends on the pyo3 crate. This is not exposed through the public API and it should work from extension modules not using pyo3 directly. It’ll nevertheless still bring the dependency in, so this might be considered if the module doesn’t want to use it.

Simple usage

Each extension module has its own global variables, therefore the used logger is also independent of other Rust native extensions. Therefore, it is up to each one to set a logger for itself if it wants one.

By using init function from a place that’s run only once (maybe from the top-level module of the extension), the logger is registered and the log messages (eg. info) send their messages over to the Python side.

use log::info;
use pyo3::prelude::*;

#[pyfunction]
fn log_something() {
    info!("Something!");
}

#[pymodule]
fn my_module(m: Bound<'_, PyModule>) -> PyResult<()> {
    pyo3_log::init();

    m.add_wrapped(wrap_pyfunction!(log_something))?;
    Ok(())
}

Performance, Filtering and Caching

Ideally, the logging system would always consult the Python loggers to know which messages should or should not be logged. However, one of the reasons of using Rust instead of Python is performance. Part of that is giving up the GIL in long-running computations to let other threads run at the same time.

Therefore, acquiring the GIL and calling into the Python interpreter on each trace message only to figure out it is not to be logged would be prohibitively slow. There are two techniques employed here.

First, level filters are applied before consulting the Python side. By default, only the Debug level and more severe is considered to be sent over to Python. This can be overridden using the filter and filter_target methods.

Second, the Python loggers and their effective log levels are cached on the Rust side on the first use of the given module. This means that on a disabled level, only the first logging attempt in the given module will acquire GIL while the future ones will short-circuit before ever reaching Python.

This is good for performance, but could lead to the incorrect messages to be logged or not logged in certain situations ‒ if Rust logs before the Python logging system is set up properly or when it is reconfigured at runtime.

For these reasons it is possible to turn caching off on construction of the logger (at the cost of performance) and to clear the cache manually through the ResetHandle.

To tune the caching and filtering, the logger needs to be created manually:

let handle = Logger::new(py, Caching::LoggersAndLevels)?
    .filter(LevelFilter::Trace)
    .filter_target("my_module::verbose_submodule".to_owned(), LevelFilter::Warn)
    .install()
    .expect("Someone installed a logger before us :-(");

// Some time in the future when logging changes, reset the caches:
handle.reset();

Mapping

The logging target is mapped into the name of the logger on the Python side, replacing all :: occurrences with . (both form hierarchy in their respective language).

Log levels are mapped to the same-named ones. The Trace doesn’t exist on the Python side, but is mapped to a level with value 5.

Interaction with Python GIL

Under the hook, the logging routines call into Python. That means they need to acquire the Global Interpreter Lock of Python.

This has several consequences. One of them is the above mentioned performance considerations.

The other is a risk of deadlocks if threads are used from within the extension code without releasing the GIL.

use std::thread;
use log::info;
use pyo3::prelude::*;

#[pyfunction]
fn deadlock() {
    info!("This logs fine");

    let background_thread = thread::spawn(|| {
        info!("This'll deadlock");
    });

    background_thread.join().unwrap();
}

The above code will deadlock, because the info call in the background thread needs the GIL that’s held by the deadlock function. One needs to give up the GIL to let the other threads run, something like this:

use std::thread;
use log::info;
use pyo3::prelude::*;

#[pyfunction]
fn dont_deadlock(py: Python<'_>) {
    info!("This logs fine");

    py.allow_threads(|| {
        let background_thread = thread::spawn(|| {
            info!("This'll not deadlock");
        });

        background_thread.join().unwrap();
    });
}

Structs

• Logger
  The Logger
• ResetHandle
  A handle into a Logger, able to reset its caches.

Enums

• Caching
  What the Logger can cache.

Functions

• init
  Similar to try_init, but panics if there’s a previous logger already installed.
• try_init
  Installs a default instance of the logger.